--[[
  Instrumentation Functions
  
  Copyright (c) 2007 Brett Lajzer
  
  See LICENSE for license information.

This is code to do instrumentation and profiling.
 Call 'instr_begin' to start instrumentation, passing an identifier string
 Call 'instr_end' to stop instrumentation, passing the same identifier
 Call 'instr_track' where the first argument is an id and the second a value
    to track the value of a variable across a number of arbitrary samples
 'instr_stats' outputs gathered information to stdout.

 For example:
   instr_begin("sin")
   sin(x)
   instr_end("sin")
--]]

--keep vars in a local environment for cleanliness
do
  local event_log = {}
  local run_time = {}
  local temp_time = {}
  local call_count = {}
  local var_track = {}
  local temp_start = get_ticks()

  --starts instrumentation for an id
  function instr_begin(id)
    --check to see that we're not trying to nest these calls
    --and throw an error if we are
    if temp_time[id] ~= nil then
      error("ERROR: Attempt to nest instrumentations for same id: "..id)
    end
  
    --increment call counter
    if call_count[id] then
      call_count[id] = call_count[id] + 1
    else
      call_count[id] = 1
    end
    
    --store current time in ms
    temp_time[id] = get_ticks()  
  end
  
  
  --end instrumentation for an id
  function instr_end(id)
    --check to make sure we're ending a running instrumentation
    -- throw an error if not.
    if temp_time[id] == nil then
      error("ERROR: Can't end instrumentation on id: "..id..". Instrumentation not started.",2)
    end
       
    --add current time delta to total for id
    if run_time[id] then
      run_time[id] = run_time[id] + (get_ticks() - temp_time[id])
    else
      run_time[id] = get_ticks() - temp_time[id]
    end
    
    --delete temp entry to enable error detection
    temp_time[id] = nil    
  end
  
  
  --track the value of a variable
  function instr_track(id, val)
    if var_track[id] == nil then
      var_track[id] = {}
    end
    local pos = #var_track[id]+1
    var_track[id][pos] = val
  end
  
  
  --prints out statistics for all ids
  -- TODO: make printout of tracked values do min/max
  function instr_stats()
    local total_time = get_ticks() - temp_start
    
    --print statistics
    print(string.char(27).."[1;38;40m\nCALL STATISTICS")
    print("==============="..string.char(27).."[0;38;40m")
    for k,v in pairs(call_count) do
      print(string.char(27).."[1;32m"..k..string.char(27).."[0;38;40m")
      print("\tCalls: "..v)
      print("\tAvg: "..string.format("%3.4f",(run_time[k] or 1)/v))
      print("\t% total: "..string.format("%3.4f",(run_time[k] or 1)/total_time))
    end
    
    --variable statistics
    print(string.char(27).."[1;38;40m\nVAR STATISTICS")
    print("=============="..string.char(27).."[0;38;40m")
    for k,v in pairs(var_track) do
      local sum = 0
      for i,j in pairs(v) do
        sum = sum + j
      end
      print(string.char(27).."[1;32m"..k..string.char(27).."[0;38;40m: "..string.format("%3.4f",sum/#v))
    end
    print("")
    
    --issue warnings about unended instrumentation runs
    local unended = false
    for k,v in pairs(temp_time) do
      print(string.char(27).."[1;31mWARNING:"..string.char(27).."[0;38;40m Unended instrumentation: "..k)
      unended = true
    end
    
    --issue big warning for unended instrumentations
    if unended == true then
      print("\t*******************************************")
      print("\t*   There were unended instrumentations   *")
      print("\t*  These statistics will NOT be accurate  *")
      print("\t*                                         *")
      print("\t*  Review the above warnings and fix the  *")
      print("\t* related code to ensure proper profiling *")
      print("\t*******************************************")
    end
  end


  --log event - log stores timestamp and message, along with list of "classes"
  --  the classes are passed as the extra arguments to the function
  function instr_log(msg,...)
    local classes = ""
    if arg.n ~= 0 then
      for i,v in pairs(arg) do
        if i ~= "n" then
          classes = classes..v..",,"
        end
      end
    end
    event_log[#event_log+1] = {get_ticks(), classes, msg}
  end
  
  
  --prints out the log
  function instr_print_log(...)
	local classes = {}
    local class_string
    if arg.n == 0 then
      classes = {".*"}
      class_string = "All classes"
    else
      class_string = "Classes:"
      for i,v in pairs(arg) do
        if i ~= "n" then
          classes[#classes+1] = v
          class_string = class_string.." "..v 
        end
      end
    end

    --print out entires that relate to the classes specified
    print(string.char(27).."[1;38;40m\nEVENT LOG")
    print("========="..string.char(27).."[0;38;40m")
    print(string.char(27).."[1;32m"..class_string..string.char(27).."[0;38;40m")
    for k,v in pairs(event_log) do
      local matched = false
      for i,j in pairs(classes) do
        if string.match(v[2],j) then
          matched = true
          break
        end
      end
      --print out if the classes match
      if matched == true then
        print("  "..v[1]..": "..v[3])
      end
    end
  end
  
end